feat(tracing): add PostgreSQL tracing spans - #3678
Conversation
Trace logical database operations across the DB facade, search, audit, replica fencing, and command persistence without recording arguments or raw errors. Signed-off-by: David Grochowski <dgrochowski@squareup.com> Co-authored-by: Amp <amp@ampcode.com>
|
Some additional research on more detailed alternatives: Buzz PostgreSQL trace correlation optionsDecision being consideredBuzz currently has logical datastore spans around operations such as Two possible ways to add query-level visibility are:
These approaches solve related but different problems. Query spans describe Option 1: manually add a span around every queryResulting trace shapeEach query span would normally be a Bind values, community IDs, event IDs, user data, and other high-cardinality or Advantages
Disadvantages
Prior art
The strongest implementation would therefore not be literally manual. It would Option 2: add SQLCommenter propagation to SQLxResulting SQLFor a sampled query, SQLx would append the active W3C context: SELECT * FROM events WHERE community_id = $1 AND id = $2
/*traceparent='00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01'*/PostgreSQL treats the suffix as a comment, but database logs, activity samples, Advantages
Disadvantages
Sampling behaviorSQL comments should only be injected when the active span context is valid and
This makes application-side sampling the relevant cost control. Collector-only Prior artPrisma Engines is the strongest Rust implementation. Its Rust query engine
That is substantially better than simply disabling persistence, but Prisma Direct comparison
Recommendation for BuzzDo not add either mechanism to the current PostgreSQL datastore-spans PR. The current logical spans provide useful operation-level latency with a small, If production traces show that logical operation timing is insufficient:
Consider SQLCommenter later only if all of the following are true:
In short: logical datastore spans now; SQLx slow-query events for diagnosis; References
|
wpfleger96
left a comment
There was a problem hiding this comment.
🤖 Thanks for the PR — the research comment on per-query spans vs SQLCommenter is good analysis, and operation-level logical spans is the right scope.
The architecture is solid: dedicated buzz_datastore target with an independent OTEL filter, skip_all everywhere, uniform client-kind attributes, and the HTTP↔datastore same-trace test in router.rs proves the parenting actually works. But I think three correctness gaps need fixing before this merges (inline comments have the details):
- failed operations export as ordinary successful spans — nothing records error status
- the log scrubbing strips established diagnostics well beyond the new spans (serde errors,
event_idcorrelation, auditaction/seq) - five live operations are missing annotations amid annotated neighbors
There's also a trace-volume issue: the fence-probe/poller annotations run outside any request span and export as high-volume orphan root traces at the default filter.
Minor, non-blocking: spans carry db.system.name only — db.operation.name would be nice but the span name works for Datadog. And if usage_metrics_leader_is_live keeps its annotation, worth a doc comment noting it swallows failure by design, so that span will never show error status.
| } | ||
|
|
||
| /// Inserts an event. Returns `(StoredEvent, was_inserted)` — `false` on duplicate. | ||
| #[tracing::instrument(target = "buzz_datastore", name = "insert_event", skip_all, fields(otel.kind = "client", db.system.name = "postgresql"))] |
There was a problem hiding this comment.
🤖 None of the new #[instrument] annotations record failure status — an Err propagated by ? closes the span clean, so a failed insert_event exports as an ordinary completed span. That defeats the main purpose here (spotting slow/broken datastore ops in traces).
I think the fix is to record otel.status_code = error plus a low-cardinality error class (error enum variant or SQLSTATE — never the raw SQL error text) at the operation boundary, and add an in-memory-exporter test proving a failing op closes as an error span with no sensitive attributes.
Since that makes each of the 211 annotations longer, a small local datastore_instrument-style macro would keep this from tripling the diff — probably worth doing now rather than later.
| let rows = qb | ||
| .build() | ||
| .fetch_all(pool) | ||
| .instrument(tracing::info_span!( |
There was a problem hiding this comment.
🤖 Same failure-status gap as the #[instrument] annotations (see my comment on insert_event in buzz-db/src/lib.rs) — this manual span also closes clean when fetch_all errors, and it needs the same sanitized error recording.
| Err(e) => { | ||
| tracing::warn!("failed to reconstruct event from DB row: {e}"); | ||
| Err(_e) => { | ||
| tracing::warn!("failed to reconstruct event from DB row"); |
There was a problem hiding this comment.
🤖 This drops the serde error entirely, which makes “why won’t this row decode” undebuggable. I'd keep at least the error's classification here — the blanket scrub isn't needed for the new spans since skip_all already keeps arguments off them.
| invalid_ptag = pk, | ||
| "skipping malformed p-tag in insert_mentions" | ||
| ); | ||
| tracing::debug!("skipping malformed p-tag in insert_mentions"); |
There was a problem hiding this comment.
🤖 Losing both event_id and the invalid p-tag value makes this debug line useless — you know a malformed tag was skipped but not on which event or what it looked like. Nostr event IDs are public content hashes, not tenant data, so I think event_id at minimum should stay.
| if let Err(e) = insert_mentions(&self.pool, community_id, event, channel_id).await { | ||
| tracing::warn!(event_id = %event.id, "Failed to insert mentions: {e}"); | ||
| if let Err(_e) = insert_mentions(&self.pool, community_id, event, channel_id).await { | ||
| tracing::warn!("mention insertion failed"); |
There was a problem hiding this comment.
🤖 This (and the five other mention-index failure paths that got the same treatment) now logs neither the error nor the event_id, so a mention-index write failure can't be correlated to anything. Event IDs are public hashes — keeping event_id plus the error class here is safe and keeps incidents debuggable.
| audit_entry.hash = compute_hash(&audit_entry)?.to_vec(); | ||
|
|
||
| debug!(seq, "writing audit entry"); | ||
| debug!("writing audit entry"); |
There was a problem hiding this comment.
🤖 Audit logging loses seq here, action from the span fields on log(), and the range args on verify_chain/get_entries via skip_all. The error contract in buzz-audit/src/error.rs explicitly documents per-community seq as safe, intended diagnostics — this rewrite contradicts that. I'd restore action and seq; both are low-cardinality and per-community.
| } | ||
|
|
||
| /// Enable or disable a workflow. | ||
| #[tracing::instrument(target = "buzz_datastore", name = "set_workflow_enabled", skip_all, fields(otel.kind = "client", db.system.name = "postgresql"))] |
There was a problem hiding this comment.
🤖 disable_workflows_for_owner_in_channel just below has production callers but no annotation — it disappears from the datastore picture while all its neighbors are covered.
| /// | ||
| /// Idempotent — uses `ON CONFLICT DO NOTHING`. Returns the number of rows | ||
| /// inserted, or 0 if the `pubkey_allowlist` table doesn't exist. | ||
| #[tracing::instrument(target = "buzz_datastore", name = "backfill_from_allowlist", skip_all, fields(otel.kind = "client", db.system.name = "postgresql"))] |
There was a problem hiding this comment.
🤖 mint_relay_invite, reap_expired_relay_invites, and claim_relay_invite below are unannotated live operations — coverage holes amid annotated neighbors.
| /// prevents the stale-snapshot race where a concurrent publication reads | ||
| /// older state and overwrites a newer snapshot by arrival order. | ||
| /// | ||
| #[tracing::instrument(target = "buzz_datastore", name = "publish_nip43_membership_locked", skip_all, fields(otel.kind = "client", db.system.name = "postgresql"))] |
There was a problem hiding this comment.
🤖 nip43_membership_snapshot_needs_reconciliation above carries no annotation, so traces expose only its lower-level child calls — not the logical operation this PR sets out to measure.
| /// The statements are separately awaited on a single pinned connection; | ||
| /// a single SELECT would not guarantee evaluation order across the | ||
| /// subexpressions, reopening the race this ordering exists to close. | ||
| #[tracing::instrument(target = "buzz_datastore", name = "replica_fence_sample_writer", skip_all, fields(otel.kind = "client", db.system.name = "postgresql"))] |
There was a problem hiding this comment.
🤖 This runs on the fence probe loop every 500ms (PROBE_INTERVAL) outside any request span, so each execution exports as its own single-span root trace — roughly 172k orphan traces/day/pod at the default filter, which already ships buzz_datastore=info. observe_heartbeat (per routed read) and usage_metrics_leader_is_live (per poller tick) have the same shape.
I'd drop the annotations from the probe/poller internals, or move them to a separate default-off target like buzz_datastore_probe. The startup-only ones (migrate, the floor-guard verifies) are fine.
Why
Expose PostgreSQL datastore latency within existing request traces so slow logical database operations can be identified without recording tenant data or query arguments.
What
buzz_datastoretarget anddb.system.name = "postgresql"for filtering and backend classificationRisk Assessment
Medium — this instruments frequently used datastore paths and increases trace volume when enabled, but does not change SQL execution or datastore behavior. Existing OpenTelemetry filtering controls export.
References
Generated with Amp